home *** CD-ROM | disk | FTP | other *** search
/ CU Amiga Super CD-ROM 17 / CU Amiga Magazine's Super CD-ROM 17 (1997)(EMAP Images)(GB)[!][issue 1997-12].iso / CUCD / Programming / DiceSource / doc / dprof.doc < prev    next >
Text File  |  1994-02-13  |  8KB  |  246 lines
  1.  
  2. dprof/dprof                            dprof/dprof
  3.  
  4.                    DPROF.DOC
  5.  
  6.     DPROF <proffile> [-call]
  7.  
  8.     The DPROF program generates profiling output from the binary data file
  9.     generated by an executable which was compiled with profiling enabled.
  10.  
  11.     In order to use DPROF you must compile your program with the -prof
  12.     option. There are three levels of profiling:
  13.  
  14.     -prof1    profile only your code (same as -prof with no numerical level)
  15.     -prof2    profile your code and the standard C library
  16.     -prof3    profile your code, the C library, and the amiga library tags
  17.  
  18.     To use -prof2 you must have DLIB:CSP.LIB (small data profiled c.lib)
  19.     or DLIB:CSRP.LIB (small data profiled c.lib for registered arguments).
  20.  
  21.     To use -prof3 you must have DLIB:AMIGASP20.LIB (small data profiled
  22.     amiga.lib) or DLIB:AMIGASRP20.LIB (small data profiled amiga.lib for
  23.     registerd arguments).
  24.  
  25.     Other combinations are possible depending on the options you use for
  26.     linking.  These libraries will not necessarily exist on DCC1:, they are
  27.     most likely lharc'd in DCC2:DLIB or DCC3:DLIB depending on how I've
  28.     arranged the distribution.    Registered users can make other library
  29.     combinations directly from the library source.
  30.  
  31.                 USAGE WARNINGS
  32.  
  33.     The profiling code is accurate to 20 microseconds under 2.0, 1/60
  34.     second under 1.3.  The profiling code itself will slow down a program
  35.     by quite a bit but, in general, the system makes every attempt to
  36.     filter out its profiling overhead in the statistics file (so the grand
  37.     total time will be less then the actual amount of time the program took
  38.     to run).
  39.  
  40.     Note, however, that the results will be skewed somewhat anyway, not
  41.     only due to the overhead of the profiling code, but also due to task
  42.     switches and other system overhead.  To get accurate results you should
  43.     only run the executable that is to generate a .dprof file on an
  44.     unloaded system (i.e. don't do anything else while the executable is
  45.     running).  Many calls to very short, quick routines will suffer the
  46.     most and numbers should be taken more in a qualitative fashion than a
  47.     quantitative fashion.
  48.  
  49.     Keep in mind that it is not necessary to profile everything,
  50.     particulary for large projects.  You may want most of the system to run
  51.     at full speed while only profiling a small part of it at a time.
  52.  
  53.  
  54.                      EXAMPLE
  55.  
  56.     EXAMPLE: -------------------------
  57.  
  58.     void    fubar1(void);
  59.     void    fubar2(void);
  60.     void    loop(long);
  61.  
  62.     main(ac, av)
  63.     char *av[];
  64.     {
  65.         short i;
  66.  
  67.         for (i = 0; i < 100; ++i) {
  68.         fubar1();
  69.         fubar2();
  70.         }
  71.         loop(10);
  72.         fubar1();
  73.         fubar2();
  74.     }
  75.  
  76.     void
  77.     fubar1()
  78.     {
  79.         short j;
  80.         for (j = 0; j < 10000; ++j);
  81.         fubar2();
  82.     }
  83.  
  84.     void
  85.     fubar2()
  86.     {
  87.         short j;
  88.         for (j = 0; j < 100; ++j);
  89.     }
  90.  
  91.     void
  92.     loop(n)
  93.     {
  94.         if (n)
  95.         loop(n - 1);
  96.     }
  97.  
  98.     ----------------------------------
  99.  
  100.     compile and the run the program, then dump the profile. the DPROF
  101.     program automatically appends the '.dprof' onto the filename you
  102.     specify.
  103.  
  104.     1> dcc test.c -o test -prof1
  105.     1> test
  106.     1> dprof test
  107.  
  108.  
  109. @($)DPROF V2.06.01  Sep 30 1991         test.dprof
  110.  
  111. GrandTotal:   539.53 mS
  112.  
  113. **** BY ROUTINE ****
  114.  
  115. _main    calls=1      total=  539.53 mS (100.00%) local=   10.37 mS (  1.92%)
  116. _fubar1 calls=101    total=  517.45 mS ( 95.90%) local=  507.75 mS ( 94.10%)
  117. _fubar2 calls=202    total=   20.44 mS (  3.79%) local=   20.44 mS (  3.79%)
  118. _loop    calls=11     total=    0.96 mS (  0.17%) local=    0.96 mS (  0.17%)
  119.     \_______/    \_________________________/ \__________________________/
  120.                total amount of time        amount of time spent in the routine
  121.       the number of    spent in the routing        not including profiled subroutine
  122.       calls made to    including all subroutine     calls it may make.
  123.       the routine      calls.
  124.                             The percentage is relative to
  125.             Percentage is relative to   the grand total run time
  126.             the grand total
  127.  
  128. **** BY PARENT ****
  129.  
  130.     total number of calls made to fubar2()
  131.     and total running time, same as from
  132.     the first table
  133.      ____________________________
  134.     /                 \
  135. _fubar2 calls=202    total=   20.44 mS
  136.     From _fubar1 calls=101    total=    9.69 mS ( 47.43%)
  137.     From _main     calls=101    total=   10.75 mS ( 52.56%)
  138.  
  139.     \_____________________/    \________________________/
  140.  
  141.      number of calls made to        time spent in fubar2() for calls
  142.      fubar2() from fubar1() and     made from fubar1() and main(), adds
  143.      main() respectively            up to the total on the first line.
  144.  
  145.  
  146.  
  147. _loop    calls=11     total=    0.96 mS
  148.     From _main     calls=1      total=    0.96 mS (100.00%)
  149.     From _loop     calls=1      total=    0.04 mS (  4.65%)
  150.     From _loop     calls=1      total=    0.13 mS ( 13.95%)
  151.     From _loop     calls=1      total=    0.22 mS ( 23.25%)
  152.     From _loop     calls=1      total=    0.31 mS ( 32.55%)
  153.     From _loop     calls=1      total=    0.40 mS ( 41.86%)
  154.     From _loop     calls=1      total=    0.49 mS ( 51.16%)
  155.     From _loop     calls=1      total=    0.60 mS ( 62.79%)
  156.     From _loop     calls=1      total=    0.69 mS ( 72.09%)
  157.     From _loop     calls=1      total=    0.78 mS ( 81.39%)
  158.     From _loop     calls=1      total=    0.87 mS ( 90.69%)
  159.  
  160. **** COMBINED CALL TREE ****
  161.  
  162.  
  163.     Top line contains the same information from table 1
  164.        ________________________________________________________
  165.       /                                \
  166. _main    calls=1     tot=  539.53 (100.00)  loc=   10.37 (  1.92)
  167.     _fubar1 calls=101    tot=  517.45 ( 95.90)  loc=  507.75 ( 94.10)
  168.     _fubar2 calls=101    tot=   10.75 (  1.99)  loc=   10.75 (  1.99)
  169.     _loop   calls=1    tot=    0.96 (  0.17)  loc=    0.08 (  0.01)
  170.      \___________________________________________________________/
  171.  
  172.     main() calls fubar1() 101 times, fubar1() takes 517 mS total
  173.     time over these calls.    main() calls fubar2() directly 101
  174.     times and fubar2() takes 10 mS over these calls.  Note that
  175.     fubar2()'s time is not the same as in table 1 because only
  176.     those calls made from main() are counted here.
  177.  
  178.     Percentages are relative to main()
  179.  
  180.  
  181.  
  182.     fubar1() calls fubar2() 101 times.  percentages are relative
  183.     to fubar1()'s total time.  Note that if you add fubar2()'s
  184.     number of calls and total time to the fubar2() entry above
  185.     you will get the grand total for fubar2() shown in the first
  186.     table.
  187.  
  188.      _____________________________________________________
  189.     /                              \
  190. _fubar1 calls=101   tot=  517.45 (100.00)  loc=  507.75 ( 98.12)
  191.     _fubar2 calls=101    tot=    9.69 (  1.87)  loc=    9.69 (  1.87)
  192.  
  193. _fubar2 calls=202   tot=   20.44 (100.00)  loc=   20.44 (100.00)
  194.  
  195. _loop    calls=11    tot=    0.96 (100.00)  loc=    0.96 (100.00)
  196.     <SELF>  calls=10
  197.     \_____________/
  198.  
  199.     The profiled data includes the entire call tree but for
  200.     simplicity, recursive calls are simply shown as above.
  201.  
  202.  
  203.     You can also request DPROF to print out the entire call tree.  This is
  204.     done by adding the -call option to dprof.  Note, however, that this
  205.     option may result in a huge amount of data printed out.  On the
  206.     otherhand, much of the data is quite useful especially when tracing
  207.     subroutine stacking and other things.
  208.  
  209.     1> dprof test -call
  210.  
  211.     .....
  212.  
  213. **** CALL TREE ****
  214.  
  215. _main    calls=1     tot=  539.53 (100.00)  loc=   10.37 (  1.92) {
  216.     _fubar1 calls=101    tot=  517.45 ( 95.90)  loc=  507.75 ( 94.10) {
  217.     _fubar2 calls=101   tot=    9.69 (  1.79)  loc=    9.69 (  1.79)
  218.     }
  219.     _fubar2 calls=101    tot=   10.75 (  1.99)  loc=   10.75 (  1.99)
  220.     _loop   calls=1    tot=    0.96 (  0.17)  loc=    0.08 (  0.01) {
  221.     _loop    calls=1     tot=    0.87 (  0.16)  loc=    0.08 (  0.01) {
  222.         _loop   calls=1    tot=    0.78 (  0.14)  loc=    0.08 (  0.01) {
  223.         _loop    calls=1     tot=    0.69 (  0.12)  loc=    0.08 (  0.01) {
  224.             _loop   calls=1    tot=    0.60 (  0.11)  loc=    0.11 (  0.02) {
  225.             _loop    calls=1     tot=    0.49 (  0.09)  loc=    0.08 (  0.01) {
  226.                 _loop   calls=1    tot=    0.40 (  0.07)  loc=    0.08 (  0.01) {
  227.                 _loop    calls=1     tot=    0.31 (  0.05)  loc=    0.08 (  0.01) {
  228.                     _loop   calls=1    tot=    0.22 (  0.04)  loc=    0.08 (  0.01) {
  229.                     _loop    calls=1     tot=    0.13 (  0.02)  loc=    0.08 (  0.01) {
  230.                         _loop   calls=1    tot=    0.04 (  0.00)  loc=    0.04 (  0.00)
  231.                     }
  232.                     }
  233.                 }
  234.                 }
  235.             }
  236.             }
  237.         }
  238.         }
  239.     }
  240.     }
  241. }
  242.  
  243.  
  244.  
  245.  
  246.